Yioop v10 — pollett.org Log Debug Plan
Arc Post-Mortem Summary.
A triage of the pollett.org production PHP
error log from 16-Jun-2026. It fixed a recurring “Undefined array key
USER_ID” warning in two public resource-serving methods, hardened and
audited the related paths, and chased down an HTTP/2 partial-transfer bug on
large responses whose root cause was a writable-set snapshot race in the
cooperative server. Fixes landed in HEAD to reach production on its next
pull.
Triage of the production PHP error log from
pollett.org (16-Jun-2026). The running server pulled the repo the
evening before, so it is on commit 5f6f2b4
(SocialComponent.php at 12666 lines) — that is how
the logged line numbers (12075 / 12171) map back to the source. The
mail arc has since shrunk that file, so the same code now lives at
10240 / 10336 in HEAD; fixes land in HEAD and reach
production on its next pull.
- ✓ Recurring
“Undefined array key USER_ID” warning
(
SocialComponent.php, two sites).
- Root cause: two public wiki/group resource-serving methods
call
checkAuthRequirement($data, $_SESSION['USER_ID'])
without a guard. An anonymous (not-logged-in) visitor or bot
has no USER_ID in the session, so PHP 8.5 warns
on every such request — hence the all-day recurrence.
- It was also a latent auth bug: the undefined value is
null, and null != C\PUBLIC_USER_ID,
so a guest was not being treated as the public user in the
require-signin check.
- ✓ Fixed: both sites now pass
$_SESSION['USER_ID'] ?? C\PUBLIC_USER_ID, the
idiom already used throughout the file.
checkAuthRequirement's own docblock names
PUBLIC_USER_ID as the guest sentinel, so this
clears the warning and corrects the guest path.
- ✓ Fixed “SSL: Connection
reset by peer” in
stream_get_contents
(WebSite.php:2860, parseH1Request).
- A client / bot dropped the TLS connection while the server
was still reading the request body. Transient and
environmental, not a server fault (2 occurrences all day).
- ✓ Fixed: the request-body read is now wrapped in a
temporary error handler that swallows only the
“reset by peer” notice and lets every other
warning through, then restores the previous handler. No
@ suppression; this mirrors the intent of the
existing write-side suppression near
WebSite.php:4942.
- ✓ Fixed (drain) Memory fatal
— 2 GB exhausted, tried to allocate ~1.5 GB
(
WebSite.php:4942, output drain).
- A single response of ~1.5 GB was held entirely in
memory (
$out_streams[DATA][$key]), and the drain
did substr($data, $offset) — copying the
whole unsent tail on each fwrite. That
~1.5 GB copy on top of the buffer already in memory is
what crossed the 2 GB limit. One occurrence.
- ✓ Fixed: the drain now copies at most one
MAX_IO_LEN (128 KB) block per pass instead
of the entire tail —
substr($data, $offset, $chunk_len). The socket
only accepts a bounded amount per writable event anyway, so
this costs no throughput; $offset still advances
and the periodic compaction still reclaims the sent prefix.
Peak memory is now the buffer itself, never doubled, so a
large response drains instead of OOMing.
- Where the 1.5 GB came from — corrected:
the access log at the crash second shows public-user bots
crawling wiki
history&show=<revision>
on the public group (pages 4/3). But that path is
not the 1.5 GB source: wiki content is capped at
MAX_GROUP_PAGE_LEN (512 KB) on save
(SocialComponent.php:7817) and
WikiParser::parse truncates render output to
~472 KB when handle_big_files is false (the
show path). So each history-show response is ≤~472 KB.
The 1.5 GB buffer is a different request —
most plausibly a large wiki resource / attachment served
whole and draining slowly to a stalled client, with the
history-crawling bots as concurrent memory pressure.
- NEXT (open) the drain fix
neutralizes the OOM regardless of producer. To stop a
~1.5 GB body being generated/buffered at all,
pinpoint the producer: check pollett.org for a large
file/resource on the public wiki and the access log just
before the crash second. Likely follow-up: stream
large resource bodies rather than buffering them whole.
- ✓ Resolved
(producer): the offset/limit resource branch now streams.
A second 2 GB OOM on 2026-06-22 (tried to allocate
~1.28 GB, in WebSite.php on the response side, while a
flood of bots crawled wiki history and source) traced to the
one resource-serving branch that still read whole.
ResourceController::get serves a byte window requested with
o and l (the machine-to-machine
sync path, and reachable on any public resource) by reading
the span with file_get_contents($path, false, null,
$offset, $limit). The limit comes straight off the
request as an int with no cap, so a large span (a 50 MB
sync chunk, or a crafted request naming a whole
multi-hundred-megabyte file) was read entire into memory and
then copied again into the server's response buffer, and that
copy is what crossed the 2 GB process limit and killed
the single-process server. The other three serve branches
(HTTP Range, small files under MAX_RESOURCE_SERVE_LEN, and
large no-range files) already stream or are bounded; this was
the lone whole-read. It now streams the same window in
RESOURCE_STREAM_BLOCK_LEN blocks through the same web_site
stream generator the Range and large-file branches use, with
the headers left exactly as before, so the bytes and response
are identical and memory stays bounded to one block. The exact
crash request is not in the log tail because a request that
dies mid-serve never reaches the post-serve access-log write;
this fix removes the only path that could have produced that
allocation.
- ✓ Hardening
(defense-in-depth): per-connection HTTP/2 memory ceilings.
The producer fix above removes the request that built the
oversized body, but the crash also showed the server had no
ceiling on how much it would hold for a single HTTP/2
connection. Because H2 multiplexes every stream's response onto
one per-connection outbound buffer (queueResponseData appends),
and each dispatched stream's body waits in pending_send until
its flow-control window lets it pump, a client that pipelines
requests faster than it reads the replies could grow that one
connection's state without bound — the server advertised
MAX_CONCURRENT_STREAMS=100 but did not enforce it. Now a new
stream is refused with RST_STREAM(REFUSED_STREAM) once the
connection is at 100 open streams or its buffered-byte ceiling
(H2_MAX_CONN_BUFFER, 64 MB: queued unsent + each stream's
pending response body + each stream's still-arriving request
body, summed by h2ConnectionBacklog). So no single connection
can exhaust the process regardless of which route produced the
body. A conforming client never reaches the limit since it
honors the advertisement.
- ✓ Audit of the
ignored H2 settings for other exhaustion paths. The
SETTINGS handler accepts but ignores most peer settings; checked
each for an unbounded structure a client could grow. Incoming
frames are already capped (oversized frame → GOAWAY
FRAME_SIZE_ERROR; request body → MAX_REQUEST_LEN), and the
header block is not accumulated across frames, so those are
bounded. One gap remained: pending_stream_window_credit stashes
a WINDOW_UPDATE arriving for a stream whose send window is not
yet registered, keyed by stream id, and the new byte ceiling
does not count these small entries — so a client sending
WINDOW_UPDATE for many never-opened stream ids could grow that
map without bound. Now it is capped at MAX_CONCURRENT_STREAMS
distinct streams (more than a connection can ever have open at
once); a client exceeding that is crediting streams it never
opened, which is treated as a PROTOCOL_ERROR (GOAWAY).
- ✓ Fixed MediaUpdater fatal
—
BulkEmailJob could not load
SmtpClient (require of a missing
mail/Utility.php).
- The mail-library relocation moved
SmtpClient
into src/library/mail/ but left two breaks the
daemon path tripped over. First, an inline
require_once __DIR__ . "/Utility.php" now
resolved to mail/Utility.php (one level too
deep) — file not found, fatal at load. Second, hidden
behind that, the class still called crawlLog,
changeInMicrotime and
setWorldPermissions unqualified; from the new
...\library\mail namespace those resolve to
undefined functions, so the first such call would have
fataled even once the file loaded. Web paths never hit this
because index.php loads Utility;
the MediaUpdater daemon did not.
- ✓ Fixed: a library class should not load
Utility, so the inline require is gone; the
MediaUpdater daemon now requires
Utility like the other executables, and
SmtpClient imports library as L and calls
L\crawlLog etc. A sweep of the rest of the
mail / ACME / media-job v10 classes found no other stray
requires.
- HTTP/2 partial transfer on responses past the
per-stream window (the Magazines page). A wiki page
larger than the client's initial per-stream receive window
(Firefox starts a connection at 131072 bytes) loaded
intermittently: the same page would succeed on one request and
fail with NS_ERROR_NET_PARTIAL_TRANSFER on the next. Smaller
pages, which fit inside the initial window and finish in one
burst, were never affected.
- What the traces established. The client
does extend windows, generously: it raises
SETTINGS_INITIAL_WINDOW_SIZE mid-connection (seen as
peer_initial_window jumping from 131072 to 6291456) and
sends large per-stream WINDOW_UPDATE frames (+12451840).
So a parked stream is meant to resume the moment that
credit lands. The behaviour we never saw was the credit
failing to arrive; what we saw was credit arriving and the
tail still not going out on the failing loads. Note: a
separate class of connection advertises an initial window of
0 and grants entirely per stream — for those,
peer_initial_window is genuinely 0 and seeding the send
window to 0 is correct (the default-window fallback only
applies when the value is null, never when it is a real 0).
- Dead end (recorded so it is not retried).
Pacing a large body out in frame-sized blocks through the
streaming generator does not help by itself: the streaming
path is gated by the very same per-stream send window as a
whole-body send, so it cannot push past an exhausted window
any more than sendH2Body can. Streaming does not raise the
window. Routing the page through it is not the lever.
- Root cause: a writable-set snapshot race in the
event loop. Each loop pass snapshots the set of
connections with unsent response bytes before
select, then after select reads inbound frames and finally
drains that snapshot. When a parked stream last drained its
window-sized slice it was removed from the writable set
(shutdownHttpWriteStream, correct — there was nothing
to write while its send window sat at zero). The credit
(WINDOW_UPDATE or raised SETTINGS) then arrives in the
read phase and re-pumps the stream, queueing the rest of
the body and re-arming the connection — but that
happens after the snapshot was taken, so the drain step
skips it. The bytes wait for the next select cycle; if the
peer has stopped reading by then, the tail never leaves and
the transfer ends partial. Whether the window came back in
time was a race, which is exactly why the same page passed
on one load and failed on the next.
- ✓ Fixed: the drain step now operates on the live
set of connections that have unsent bytes at that point in
the tick rather than the pre-read snapshot, so a stream
re-pumped by a just-read flow-control frame flushes in the
same pass. out_streams holds only connections with bytes
still to send, and a socket that is not yet writable simply
takes nothing this pass and is retried, so draining the live
set is safe.
- Two further crashes, 2026-07-03 and 2026-07-04. The error log
shows three identical fatals: the 2 GB process limit exhausted while
allocating ~1.3 MB in PackedTableTools::load. The
[website-memory] lines just before each fatal read
~1.95 GB used with hundreds of sessions (269, 190, 441) under a bot
flood, so the load allocation is only the straw that crosses the line;
the real growth is elsewhere (accumulating sessions/connections, and
PackedTableTools' own table_cache which has no eviction are
the leading suspects). The same logs carried ~8000 deprecation and
warning lines, nearly all from one bug:
- ✓ Cache redirect fell
through. SearchController::cacheRequest, on a missing crawl item
with a cached link, set a Location redirect header but did not
return, so it went on to format a
false crawl item.
That produced the false-to-array deprecation and the whole cascade of
undefined-key and mb_strtolower(null) warnings on every bot hit to a
stale cache URL. Adding the return stops it.
- ✓ Broken-pipe warning
logged. WebSite's streaming write wrapped fwrite in
set_error_handler(null), which restores the logging handler rather
than silencing it, so an expected SSL broken pipe from a client that
hung up was logged. The failure is already handled by the return-false
check, so the write now uses @fwrite and the warning is silenced.
- A handful of low-volume SocialComponent warnings (undefined
$page_id, array offset on false) remain to be pinned down against the
production line numbers.